Skip to content

feat: add client debug logging support for streaming gRPC calls#2336

Closed
parthea wants to merge 2 commits intomainfrom
add-unary-stream-logging
Closed

feat: add client debug logging support for streaming gRPC calls#2336
parthea wants to merge 2 commits intomainfrom
add-unary-stream-logging

Conversation

@parthea
Copy link
Contributor

@parthea parthea commented Feb 14, 2025 •
edited
Loading

Fixes #2289

Also see necessary changes in googleapis/python-api-core#794 to add logging in the response iterator each time a chunk is received in the stream.

Sync Server Streaming

tests/system/test_streams.py 
{"timestamp": "2025-02-19 14:31:06,113", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.client", "message": "Created client `google.showcase_v1beta1.EchoClient`.", "serviceName": "google.showcase.v1beta1.Echo", "credentialsType": "builtins.NoneType", "universeDomain": ""}
{"timestamp": "2025-02-19 14:31:06,130", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"The\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,131", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"hail\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,132", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"in\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,133", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"Wales\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,134", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"falls\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,135", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"mainly\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,135", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"on\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,136", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"the\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,137", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"snails.\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
.
============================== 1 passed in 4.24s ===============================

Async Server Streaming

tests/system/test_streams.py 
{"timestamp": "2025-02-14 22:09:14,950", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.async_client", "message": "Created client `google.showcase_v1beta1.EchoAsyncClient`.", "serviceName": "google.showcase.v1beta1.Echo", "credentialsType": "builtins.NoneType", "universeDomain": ""}
{"timestamp": "2025-02-14 22:09:14,959", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc_asyncio", "message": "Sending request for b'/google.showcase.v1beta1.Echo/Expand'", "rpcName": "b'/google.showcase.v1beta1.Echo/Expand'", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"content\": \"The hail in Wales falls mainly on the snails.\"\n}", "requestMethod": "grpc", "metadata": {"showcase-trailer": "hello world", "x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.1 gapic/0.0.0"}}, "metadata": {"showcase-trailer": "hello world", "x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.1 gapic/0.0.0"}}
{"timestamp": "2025-02-14 22:09:14,967", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"The\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,969", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"hail\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,970", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"in\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,971", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"Wales\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,972", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"falls\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,973", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"mainly\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,973", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"on\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,974", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"the\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,975", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"snails.\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
.

@parthea parthea self-assigned this Feb 14, 2025
@product-auto-label product-auto-label bot added the size: l Pull request size is large. label Feb 14, 2025
@parthea parthea force-pushed the add-unary-stream-logging branch from d69564c to 27463b2 Compare February 14, 2025 22:26
@parthea parthea marked this pull request as ready for review February 14, 2025 22:36
@parthea parthea requested a review from a team as a code owner February 14, 2025 22:36
@product-auto-label product-auto-label bot added size: xl Pull request size is extra large. and removed size: l Pull request size is large. labels Feb 14, 2025
@parthea parthea added owlbot:run Add this label to trigger the Owlbot post processor. size: l Pull request size is large. and removed size: xl Pull request size is extra large. labels Feb 14, 2025
@gcf-owl-bot gcf-owl-bot bot removed the owlbot:run Add this label to trigger the Owlbot post processor. label Feb 14, 2025
@parthea parthea assigned vchudnov-g and ohmayr and unassigned parthea Feb 19, 2025
@parthea parthea requested review from ohmayr and vchudnov-g February 19, 2025 14:34
@product-auto-label product-auto-label bot added size: xl Pull request size is extra large. and removed size: l Pull request size is large. labels Feb 20, 2025
@parthea parthea force-pushed the add-unary-stream-logging branch from 9519eda to d190cba Compare March 31, 2025 09:37
@product-auto-label product-auto-label bot added size: l Pull request size is large. and removed size: xl Pull request size is extra large. labels Mar 31, 2025
ohmayr
ohmayr reviewed Apr 3, 2025
View reviewed changes
gapic/templates/%namespace/%name_%version/%sub/services/%service/transports/grpc.py.j2

class _LoggingClientInterceptor(grpc.UnaryUnaryClientInterceptor): # pragma: NO COVER
class _LoggingClientInterceptor(grpc.UnaryUnaryClientInterceptor, grpc.UnaryStreamClientInterceptor): # pragma: NO COVER
def intercept_unary_stream(self, continuation, client_call_details, request):
Copy link
Contributor

@ohmayr ohmayr Apr 3, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we add a note here to clarify that:

  • request logging for streaming calls lives in the generator but response logging for streaming calls lives in python-api-core, briefly explaining why.
  • request / response logging for unary calls lives in the generator.

This'll make it easier for us to track down the implementation in the future.

Copy link
Contributor Author

@parthea parthea May 9, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed in 84c7986

@vchudnov-g
Copy link
Contributor

vchudnov-g commented Apr 3, 2025

I don't think I've encountered the term "unary-stream" before, and it took me seeing the examples in the PR description to be sure I understood what you meant. I suggest using standard terminology, "server streaming", or clarifying that that's what you mean by "unary-stream".

Furthermore, this "logging-stream-from-the-server" functionality should also apply to bidi streaming. Does it? Do we have an example/golden? (Apologies if I've missed it; I focused this review on just looking at the redis golden files)

@parthea parthea changed the title feat: add client debug logging support for unary-stream gRPC calls feat: add client debug logging support for streaming gRPC calls May 9, 2025
@parthea parthea assigned parthea and unassigned vchudnov-g and ohmayr May 9, 2025
@parthea
Copy link
Contributor Author

parthea commented May 9, 2025

Unary Stream is a term used in gRPC. I can't change any references to that but I have updated terminology in this PR which can be changed to use Server Streaming instead of Unary-Stream
https://grpc.github.io/grpc/python/grpc.html#grpc.UnaryStreamClientInterceptor.intercept_unary_stream

@parthea parthea removed their assignment Oct 9, 2025
@parthea parthea closed this Oct 15, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@ohmayr ohmayr ohmayr left review comments

@vchudnov-g vchudnov-g Awaiting requested review from vchudnov-g

Assignees

No one assigned

Labels

size: l Pull request size is large.

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

[logging] add client logging support for gRPC streaming RPCs

3 participants

@parthea @vchudnov-g @ohmayr